#!/usr/bin/env python

from config import *
import sys

import logging
LOGFILENAME = __file__ + ".log"
logging.basicConfig(format='%(asctime)s %(levelname)s: %(message)s',
      filename = LOGFILENAME, level=logging.INFO)
logger = logging.getLogger("fileWatcher")

from errorCollator import *
hiccups = ErrorCollator()

def dumpHiccups():
  if hiccups.hasErrors():
    import socket
    thisHost = socket.gethostbyaddr(socket.gethostname())
    fqdn = thisHost[1][0]
    # hiccups.dump()
    hiccups.emailAlert("fileWatcher@"+fqdn, EMAIL_ALERT_LIST, EMAIL_SMTP_HOST) 

import re
import os.path
from fileHandlers.sfrmProcess import SFRM
from fileHandlers.oxfordProcess import OXFORD
logger.info("Connecting CSAF ProposalDB")
from ZSI import FaultException 
from pdbWrapper import PDBWS
try:
  pdbcnx = PDBWS(PDBWSURL,PDBWSUSER,PDBWSPASS)
except Exception, e:
  logger.critical(e)
  hiccups.add(Error(__name__,__file__,e) )
  hiccups.add(Error(__name__,__file__,"Unable to establish communication with " +
                  PDBWSURL + " Aborting.") )
  dumpHiccups()
  sys.exit(1)


from icatAdminWrapper import ICATAWS
from icatWrapper import ICATWS
from ZSI import FaultException 

icatacnx = None
sessionId = None
icatcnx = None

def icatReconnect():
    global icatacnx
    global sessionId
    global icatcnx
    logger.info("Connecting: ICAT admin")
    try:
      icatacnx = ICATAWS(ICATADMINURL,ICATADMINUSER,ICATADMINPASS)
    except Exception, e:
      logger.critical(e)
      hiccups.add(Error(__name__,__file__,e) )
      hiccups.add(Error(__name__,__file__,"Unable to establish communication with " +
                      ICATADMINURL + " Aborting.") )
      return False
    
    sessionId = icatacnx.sessionId
    
    logger.info("Connecting: ICAT WS")
    try:
      icatcnx = ICATWS(ICATURL,ICATUSER,ICATPASS,sessionId)
    except Exception, e:
      logger.critical(e)
      hiccups.add(Error(__name__,__file__,e) )
      hiccups.add(Error(__name__,__file__,"Unable to establish communication with " +
                      ICATURL + " Aborting.") )
      return False
    sessionId = icatcnx.login(ICATUSER,ICATPASS);
    return True

if not icatReconnect():
  dumpHiccups()
  sys.exit(1)
    
logger.debug(str(sessionId) )
logger.debug(str(icatcnx.listInstruments(sessionId)) )
logger.debug(str(icatcnx.listDatasetTypes(sessionId)) )
logger.debug(str(icatcnx.listInvestigationTypes(sessionId)) )
logger.debug(str(icatcnx.listDatasetStatus(sessionId)) )
#logger.info(icatcnx.listParameters(sessionId)
#logger.info(icatcnx.listDatafileFormats(sessionId)
#logger.info(icatcnx.listRoles(sessionId)
#logger.info(icatcnx.searchByUserSurname(sessionId,"Turner")
#invs = icatcnx.getMyInvestigations(sessionId)
#logger.info(invs
#invHolder =  icatcnx.getInvestigation(sessionId,5700)


def methodDump(holder):
   attribs = holder.__class__.__dict__
   variables = {}
   getters = {}
   setters = {}
   sundries = {}
   for attrib,typ in attribs.iteritems():
      if type(typ) == type(methodDump): 
         if attrib[0:4]=="set_":
           setters[attrib] = typ
         elif attrib[0:4]=="get_":
           getters[attrib] = typ
         else:
           sundries[attrib] = typ
      else:
        variables[attrib] = typ
   logger.debug(str(getters.keys() ))
   logger.debug(str(variables.keys() ))

def datasetsDump(list):
   logger.debug("datasets: %d" , len(list))
   for dataset in list:
     logger.debug("%s %s %s", dataset._id, dataset._name, dataset._datasetType)
     if not hasattr(dataset, "_datafileCollection"): continue
     datafiles = dataset._datafileCollection
     logger.debug("datafiles %d" , len(datafiles))
     logger.debug("")
     if len(datafiles)<=0: continue
     datafile0 = datafiles[0]
     try: 
       logger.debug("%s %s" , datafile0._name, datafile0._datafileVersion )
       logger.debug(str( vars(datafile0._datafileFormat._datafileFormatPK)) )
       logger.debug("  %s" , datafile0._datafileModifyTime)
     except Exception, e:
       logger.warning(e)


logger.info("Connecting: Bruker Database")
from xmlMapping.dbConnect import *
bypass=False
try:
  dbcnx = DBConnection(bypass)
  dbcnx.psycopg2Init(BRKDBHOST, BRKDBPORT, BRKDBNAME, BRKDBUSER, BRKDBPASS)
  dbcnx.connect()     # establish tcp communication
    #dbcnx.query("SET search_path TO scd,public")  # only for psycopg2?
  dbcnx.cursor.execute("SET search_path TO scd,public")  # only for psycopg2?
except Exception, e:
  logger.critical(e)
  hiccups.add(Error(__name__,__file__,e) )
  hiccups.add(Error(__name__,__file__,"Unable to establish communication with " +
                  BRKDBHOST + " Aborting.") )
  dumpHiccups()
  sys.exit(1)


ICATTEMPLATE = "map-csaf_apex2icat.xml"
logger.info("Loading ICAT XML generation template %s", ICATTEMPLATE)
from xmlMapping.templateParser import TemplateParser
try:
  newIcatTemplateWalker = TemplateParser()
  newIcatTemplateWalker.registerDBConnection(dbcnx)
  newIcatTemplateWalker.initTemplate(ICATTEMPLATE)
except Exception, e:
  logger.critical(e)
  hiccups.add(Error(__name__,__file__,e) )
  hiccups.add(Error(__name__,__file__,"Unable to load XML template " +
                  ICATTEMPLATE + " Aborting.") )
  dumpHiccups()
  sys.exit(1)

OLDICATTEMPLATE = "map-csaf_apex2icat-upd.xml"
logger.info("Loading ICAT XML amend template %s", OLDICATTEMPLATE)
try:
  oldIcatTemplateWalker = TemplateParser()
  oldIcatTemplateWalker.registerDBConnection(dbcnx)
  oldIcatTemplateWalker.initTemplate(OLDICATTEMPLATE)
except Exception, e:
  logger.critical(e)
  hiccups.add(Error(__name__,__file__,e) )
  hiccups.add(Error(__name__,__file__,"Unable to load XML template " +
                  OLDICATTEMPLATE + " Aborting.") )
  dumpHiccups()
  sys.exit(1)

NOVATEMPLATE = "map-csaf_nova2icat.xml"
logger.info("Loading NOVA ICAT XML template %s", NOVATEMPLATE )
try:
  novaIcatTemplateWalker = TemplateParser()
  novaIcatTemplateWalker.initTemplate(NOVATEMPLATE)
except Exception, e:
  logger.critical(e)
  hiccups.add(Error(__name__,__file__,e) )
  hiccups.add(Error(__name__,__file__,"Unable to load XML template " +
                  NOVATEMPLATE + " Aborting.") )
  dumpHiccups()
  sys.exit(1)




def myDataFolderHandler(path, sample, mode, collection):
  """ We need to register this as a callback func to simplify
      the FolderRecurser. I.e. we try vainly to localize the 
      file format specific handling to here. 
  """
  name = None
  if not collection.dataFilesExist:
    logger.warning("Not processing %s until datafiles present.",path)
    if mode == "create":
      # Or should we set a bogus timestamp in our records:
      collection.lastModified = 0   #  Jan 1 1970 - well before first pass
      # record initial alert for email to   manager  
      hiccups.add(Error(sample,path,"No data files exist, yet ..."))
      # and pretend we handled it: 
      return True
    else:
      return
     
  # we just need a datafile to get the version number ...
  datasetFolders = collection.dataFiles 
  for folder in datasetFolders.keys():
    recent = datasetFolders[folder]['recentFileList']
    expired = datasetFolders[folder]['expiredFileList']
    if len(recent)>0:
      name = recent[0] 
      break
    elif len(expired)>0:
      name = expired[0] 
      break
  logger.debug("%s %s %s", mode , sample, name)
#  if collection.dataFormat != DataFormats.SMART:
#    logger.info("==================SKIPPING NON SMART============"
#    return

#  logger.info("==================BYPASSING HANDLER============"
#  return
    
  # BRUKER SPECIFIC
  if collection.dataFormat in [DataFormats.SMART, DataFormats.APEX]:
    try:
      res = dbcnx.query("SELECT samples_id, sample_name, revision, when_created FROM samples WHERE sample_name='%s' ORDER by revision DESC" % sample)
    except DBConnectSQLSyntaxException, msg:
      hiccups.add(Error(sample,path,msg))
      logger.info("Select from samples failed\n%s" , msg )
      return
    except DBConnectSQLResultException, msg:
      hiccups.add(Error(sample,path,msg))
      logger.info("Select from samples failed\n%s" , msg )
      return
  
    fnames = [ 'samples_id', 'sample_name', 'revision', 'when_created']
    for i in range(len(fnames)):
            logger.debug('%-15s%-15s%-15s%-15s' , fnames[i] )
    # Next, print out the instances.
    samples = []
    for i in range(res.ntuples):
          samples.append([])
          strn = ""
          for j in range(res.nfields):
                  samples[i].append(res.getvalue(i, j))
                  try:
                      strn = strn + "%-15s" % res.getvalue(i, j)
                  except:
                      logger.info(strn(res.getvalue(i, j)) )
          logger.debug(strn)
    res.clear()
  # End of Bruker specific

  try:
    l_id = int(pdbcnx.xgetLogIdFromDataset(sample)['l_id'])
    log  = pdbcnx.xgetLogFromId(l_id)
    #print log
    s_id = int(log['s_id'])
    sampledata = pdbcnx.xgetSampleFromId(s_id)
    logger.info(" submissionID:  %s",sampledata['submissionid'])
    users = pdbcnx.xgetScientistBeans(l_id)
    scientists = users['scientists'] 
    for scientist in scientists: 
      logger.debug("        %s %s",scientist['first_Names']," ",scientist['last_Name'])
  except FaultException, e:
    hiccups.add(Error(sample,path,e))
    hiccups.add(Error(sample,path,"No logged users associated with sample" ))
    logger.warning(e)
    return
    

  logger.debug(str(log) )
  logger.debug(str(sampledata))
  #
  # Pull metadata from file
  # -----------------------
  #

  fname = os.path.split(name)[-1]
  file= open(name)
  if collection.dataFormat in [DataFormats.SMART, DataFormats.APEX]:
    sf = SFRM(file)
    meta =  sf.getMetadata()
    logger.debug("    V:%2s  user: %-21s  %s", (meta["VERSION"], meta["USER"], fname) )
  elif collection.dataFormat == DataFormats.NOVA:
    sf = OXFORD(file)
    meta =  sf.getMetadata()
    logger.debug("    V:%2s  user: %-21s  %s", (meta["version"], meta["manufact"], fname) )
  file.close()

  cif = None
  if collection.dataFormat == DataFormats.NOVA and \
     collection.hierarchy['folders'].has_key('struct/tmp'):
    cifholder = collection.hierarchy['folders']['struct/tmp']
    from fileHandlers.cifHandler import ODCIF
    from os.path import split
    for recent in cifholder['recentFileList']:
      logger.debug(str(recent))
      if recent[2] != 'cif': 
        continue
      dir,cifname = split(recent[0])
      if not cifname == sample + '.cif': 
        continue
      ciffile = open(recent[0])
      cfh = ODCIF(ciffile)
      cif = cfh.getMetadata()
      break

  logger.info("CIF file: %s" , cif)
  #
  # Hit ICAT for existing entries
  # -----------------------------
  #
  investigationName =  sample
  logger.info("Retrieving ICAT investigation data for %s", investigationName)
  from icatWS.ICATService_types import ns0
  advSearchDetails= ns0.advancedSearchDetails_Def("dummy")
  advSearchDetails._caseSensitive=True
  advSearchDetails._investigationName = investigationName
  #advSearchDetails._investigationInclude = "DATASETS_ONLY"
  advSearchDetails._investigationInclude = "DATASETS_AND_DATAFILES"
  try: 
    invHolderList =  icatcnx.searchByAdvanced(sessionId,advSearchDetails)
  except Exception, e:
    hiccups.add(Error(sample,path,e))
    #hiccups.add(Error(sample,path,"No logged users associated with sample" ))
    # possibly the sessionId has timed out. it had an hour 
    # but this could be slow ...
    # maybe we could respawn the connection?
    logger.warning("Attempting ICAT reconnection..." )
    if not icatReconnect():
       hiccups.add(Error(sample,path,e))
       logger.critical("Unexpected error: %s", sys.exc_info()[0] )
       logger.critical(e)
       # this is fatal!
       dumpHiccups()
       sys.exit(1)
    logger.warning("Sucess during ICAT reconnection..." )
    # now try query again ...
    try: 
      invHolderList =  icatcnx.searchByAdvanced(sessionId,advSearchDetails)
    except Exception, e:
      hiccups.add(Error(sample,path,e))
      logger.error("Unexpected error: %s", sys.exc_info()[0] )
      logger.error(e)
      # maybe this should also be fatal? 

  # did we get a match? If not, then its a new investigation ...
  if invHolderList: 
    logger.info("Need to update existing records for %s .......",sample)
    logger.debug(type(invHolderList) )
    invHolder = invHolderList[0]
    logger.debug("facility = %s",invHolder.Facility)
    logger.debug(str(vars(invHolder)) )
    datasets = invHolder.DatasetCollection
    datasetsDump(datasets)
  else: 
    logger.info("No prior records for %s in ICAT!", sample)
    datasets = []

  # Which template to choose?
  if not datasets:
    if collection.dataFormat == DataFormats.NOVA:
      templateWalker = novaIcatTemplateWalker
    else: 
      templateWalker = newIcatTemplateWalker
  else:
    if collection.dataFormat == DataFormats.NOVA:
      templateWalker = novaIcatTemplateWalker
    else: 
      templateWalker = oldIcatTemplateWalker
  logger.info("Template walking: %s", templateWalker.templateFile )
  

  # these parameters are all accessible to the template parser
  params = {
      'LOG':        log,              # proposal system
      'USERS':      scientists,       # proposal system
      'DATASETS':   datasets,         # ICAT prior injected datafiles
      'PATH':       path,
      'SAMPLE':     sample,
      'CIF':        cif,
      'SAMPLEID':   int(log['l_id']),
      'FILEDATA':   collection,
      'MODE':       mode,
      'PURGE':      [],          # query this on return for files to delete
      'NAME':       sample  }

  if collection.dataFormat in [DataFormats.SMART, DataFormats.APEX]:
    params['SAMPLEDATA'] = sampledata       # proposal system
    if len(samples)>0:
      params['SAMPLEID'] =   samples[0][0]    # Bruker db
      params['SNAME'] =      samples[0][1]    # Bruker db
      params['REVISION'] =   samples[0][2]    # Bruker db
    else:    # no bruker database entry
      params['SNAME'] =      sample
      params['REVISION'] =   1

  logger.debug("params: %s", str(params) )

  try: 
      # apply XML generating template to 
      # everything we know about the current sample
      templateWalker.applyTemplate(params)
  except Exception, msg:
      import traceback
      exc_type, exc_value, exc_traceback = sys.exc_info()
      slist = traceback.format_tb(exc_traceback )
#      traceback.print_exc(file=sys.stdout)
      logger.critical(str(slist[-1]))
      logger.critical(msg)
      hiccups.add(Error(sample,path,str(slist[-1])))
      hiccups.add(Error(sample,path,msg))
      hiccups.add(Error(sample,path,"Couldn't walk the template. Error in expectations"))
      # potentially this is a common template failure for many samples...?
      return

  logger.info("Walked template %s", templateWalker.templateFile )
  xmlDataDict = templateWalker.genData

  # build a filename for dumping the XML to disk
  # in principle we could 
  sname = params['SAMPLE'] 
  rev = "1"
  if params.has_key('REVISION') and params['REVISION'] >1:
    rev = str(params['REVISION'])
  sname = sname + '-' + rev 
  fname = os.path.join(ICATXMLDATA , sname +"-01" + ".xml" )
  upd = 1
  #build a version number
  while os.access(fname, os.F_OK):   # already exists - so preserve previous files
      upd = upd + 1
      tname = sname + "-%02d" % (upd)
      fname = os.path.join(ICATXMLDATA , tname + ".xml" )

  DEBUG=0
  if DEBUG & 32:
         if xmlDataDict != None:
              import pprint
              pprint.pprint(xmlDataDict, indent=1)

  if not xmlDataDict:
      # something unexpected went wrong. No idea what.
      logger.warning("No data for %s ?????????", sample)
      return

  # otherwise
  # save the datastructure as XML to disc.
  icatxmlfile = writeXMLFile(fname,xmlDataDict)
  logger.info("Wrote XML instance %s", icatxmlfile)

  if len(params['PURGE'])>0:
    logger.info("%d old files to be purged from ICAT", len(params['PURGE']) )


  logger.warning("Aborting at purge - before ingest...")
  return True

  if len(params['PURGE'])>0:
    #gotta purge these before we can re-ingest modified
    for file in params['PURGE']:
      datafileId = file['datafile']
      try:
        #remove =  icatcnx.deleteDataFile(sessionId,datafileId)
        remove =  icatcnx.removeDataFile(sessionId,datafileId)
        logger.debug("purged %s %s", datafileId, file['filename'] ) 
      except Exception, e:
        logger.debug("purge failed for %s", datafileId )
        logger.debug(e)
        hiccups.add(Error(sample,file,"can't purge modified file from ICAT "))

  # in principle, now we could  
  file = open(icatxmlfile)
  xmldata = file.read()
  file.close()
  start = time.time()
  success = "AAAAHhhhhh bugger!"
  try: 
    logger.info("Ingesting at: %s", time.ctime(start) )
    success = icatcnx.ingestMetadata(sessionId,xmldata)
    stop = time.time()
  except Exception, e:
    stop = time.time()
    logger.warning("Ingest FAILED: %s", time.ctime(stop) )
    logger.warning("elapsed time: %s ", time.strftime("%d $%H:%M:%S",stop-start) )
    hiccups.add(Error(sample,path,"Couldn't ingest metadata for file "+icatxmlfile))
    logger.info(e)
    # move file to failed folder
    failed = os.path.join(ICATXMLDATA , FAILED)
    if not os.access(failed,os.F_OK):
       os.mkdir(failed, 0755)
    last_part = os.path.split(icatxmlfile)[1]
    os.rename(icatxmlfile, os.path.join(failed, last_part))
    return
  logger.info("ingest complete at: %s", time.ctime(stop))
  logger.info("elapsed time: %s", time.strftime("%d %H:%M:%S",stop-start) )
  
  logger.info(success)
  logger.info("Done!\n\n")

  return True   # all else is None




def writeXMLFile(filepath,xmlMappedDict):
  from xml.sax.saxutils import XMLGenerator
  from xmlMapping.xml2dict import BinXMLSAXParser
  p = BinXMLSAXParser()
  p.d = xmlMappedDict
                                         #defaults to iso-8859-1
  file = open(filepath,'w') 
  p.setContentHandler(XMLGenerator(file,'UTF-8'))
  p._cont_handler.startDocument()
  p.__parse__(xmlMappedDict)
  p._cont_handler.endDocument()
  file.close()
  return filepath



if __name__ == '__main__':
  import os
  import sys
  import cPickle
  import time
  from folders import *
  stopTime = time.time() # now - UNIX seconds since epoch
  verbose=True
  if len(sys.argv)>1:
    if sys.argv[1]=='-q': verbose=False

  try:
    minxTime=os.path.getmtime(DATAMINX)
    # if the next call fails then we can't save state and 
    # checking becomes very inefficient 
    # actually, minxTime would never get reset.
    # so we would be endlessly trying to reharvest same data
    os.utime(DATAMINX,(minxTime,minxTime))
  except Exception, e: 
    # probably the file doesn't exist
    minxTime=0
    logger.critical("Unable to stat/touch record file: %s", DATAMINX)
    logger.critical("Aborting!")
    hiccups.add(Error(__name__,__file__,e) )
    dumpHiccups()
    sys.exit(1)

  try:
    dataFolderMap = cPickle.load(open(DATAMINX, 'rb'))
    # dict map of full folderpathname: last modified time
    if type(dataFolderMap) != type({}):
      dataFolderMap = {}
  except EOFError:
    logger.warning("Empty record file %s", DATAMINX )
    dataFolderMap = {}
  except Exception, e:
    logger.info(sys.exc_info()[0] )
    # probably the file doesn't exist
    logger.critical("Unable to open record file %s", DATAMINX)
    logger.critical("Aborting! " )
    hiccups.add(Error(__name__,__file__,e) )
    dumpHiccups()
    sys.exit(1)

  for folder in FOLDERS:
    try:
      info = os.stat(folder)
      logger.info("Watching %s", folder)
    except Exception, e:
      logger.critical("Unable to stat folder: %s", folder)
      logger.critical("Aborting!")
      hiccups.add(Error(__name__,__file__,e) )
      hiccups.add(Error(__name__,__file__,"Maybe the data file system isn't mounted?") )
      dumpHiccups()
      sys.exit(1)

  period = (minxTime,stopTime) # harvest within this time frame
  fr = FolderRecurser(period, dataFolderMap)
  fr.verbose = verbose
  fr.dataCollectionHandler = myDataFolderHandler  # register 
  fr.assessFolder("/",FOLDERS) # pretend FOLDERS are children of /

  # write newly modified map back to disc, then quit
  cPickle.dump(dataFolderMap,open(DATAMINX ,'wb')) 
  # touch to set last access/modified time
  os.utime(DATAMINX,(stopTime,stopTime))
  # that was equivalent to shell touch /var/lib/dataMINX
  logger.info("previous %s", time.ctime(minxTime) )
  logger.info(" started %s", time.ctime(stopTime) )
  logger.info("     now %s", time.ctime(time.time()) )

  try:
    dbcnx.finish()
    pdbcnx.logout()
    icatcnx.logout(sessionId)
    icatacnx.logout(sessionId)
  except:
    pass

  dumpHiccups()
  # all done
